From 154948837afbbfc312764b24982ba7dbac0d4ebd Mon Sep 17 00:00:00 2001
From: Aleksey Kladov <aleksey.kladov@gmail.com>
Date: Sun, 8 Apr 2018 11:37:05 +0300
Subject: [PATCH] Don't print profiling information twice

It's important to `.clear` the messages so that we don't print them
again for the next "profiling session". It might be argued that really
we should have a single "profiling session" for Cargo, but we don't at
the moment.

And, while we are at it, let's lock stdout as well, so that we won't
get confused when Cargo becomes multi-threaded and prints profiling info
from several threads simultaneously.
---
 src/cargo/util/profile.rs | 36 ++++++++++++++++++++++--------------
 1 file changed, 22 insertions(+), 14 deletions(-)

diff --git a/src/cargo/util/profile.rs b/src/cargo/util/profile.rs
index 7d32adc3f..ce49eee26 100644
--- a/src/cargo/util/profile.rs
+++ b/src/cargo/util/profile.rs
@@ -4,6 +4,7 @@ use std::mem;
 use std::time;
 use std::iter::repeat;
 use std::cell::RefCell;
+use std::io::{stdout, StdoutLock, Write};
 
 thread_local!(static PROFILE_STACK: RefCell<Vec<time::Instant>> = RefCell::new(Vec::new()));
 thread_local!(static MESSAGES: RefCell<Vec<Message>> = RefCell::new(Vec::new()));
@@ -39,14 +40,24 @@ impl Drop for Profiler {
             None => return,
         };
 
-        let start = PROFILE_STACK.with(|stack| stack.borrow_mut().pop().unwrap());
+        let (start, stack_len) = PROFILE_STACK.with(|stack| {
+            let mut stack = stack.borrow_mut();
+            let start = stack.pop().unwrap();
+            (start, stack.len())
+        });
         let duration = start.elapsed();
         let duration_ms =
             duration.as_secs() * 1000 + u64::from(duration.subsec_nanos() / 1_000_000);
 
-        let stack_len = PROFILE_STACK.with(|stack| stack.borrow().len());
+        let msg = (
+            stack_len,
+            duration_ms,
+            mem::replace(&mut self.desc, String::new()),
+        );
+        MESSAGES.with(|msgs| msgs.borrow_mut().push(msg));
+
         if stack_len == 0 {
-            fn print(lvl: usize, msgs: &[Message], enabled: usize) {
+            fn print(lvl: usize, msgs: &[Message], enabled: usize, stdout: &mut StdoutLock) {
                 if lvl > enabled {
                     return;
                 }
@@ -55,26 +66,23 @@ impl Drop for Profiler {
                     if l != lvl {
                         continue;
                     }
-                    println!(
+                    writeln!(
+                        stdout,
                         "{} {:6}ms - {}",
                         repeat("    ").take(lvl + 1).collect::<String>(),
                         time,
                         msg
-                    );
+                    ).expect("printing profiling info to stdout");
 
-                    print(lvl + 1, &msgs[last..i], enabled);
+                    print(lvl + 1, &msgs[last..i], enabled, stdout);
                     last = i;
                 }
             }
-            MESSAGES.with(|msgs_rc| {
-                let mut msgs = msgs_rc.borrow_mut();
-                msgs.push((0, duration_ms, mem::replace(&mut self.desc, String::new())));
-                print(0, &msgs, enabled);
-            });
-        } else {
+            let stdout = stdout();
             MESSAGES.with(|msgs| {
-                let msg = mem::replace(&mut self.desc, String::new());
-                msgs.borrow_mut().push((stack_len, duration_ms, msg));
+                let mut msgs = msgs.borrow_mut();
+                print(0, &msgs, enabled, &mut stdout.lock());
+                msgs.clear();
             });
         }
     }
-- 
2.30.2